Improve console span exporter - #505
Conversation
Codecov Report
@@ Coverage Diff @@
## master #505 +/- ##
==========================================
- Coverage 89.33% 88.70% -0.64%
==========================================
Files 43 43
Lines 2176 2266 +90
Branches 248 258 +10
==========================================
+ Hits 1944 2010 +66
- Misses 161 178 +17
- Partials 71 78 +7
Continue to review full report at Codecov.
|
The current version of the exporter prints everything in a single line, making it difficult to read. It's also missing events, links and attributes. This commit changes the console span exporter to use multiple lines and also adds the missing information about attributes, events and links.
b0f139a to
06d1713
Compare
ocelotl
left a comment
There was a problem hiding this comment.
Just a suggestion here 👍
|
One note I'll just call out is that by providing a json representation via the console exporters, users will begin to depend on the json output of the exporter. On json in particular, it may be a better practice to create a JsonSpanExporter, and then use that in the examples (of course then people would ask why have an uglier consolespanexporter). |
|
What's the risk if people start relying on the output from the console exporter?, I think it'll only change if the internals of the span change, otherwise I think it should be quite stable. Anyway, we could make it clear that the output should not be used and that we don't guarantee any stability there. What I don't want to do is to expend time trying to create our custom representation, I tried and I found that it is very difficult to create a nice and complete one, that's the reason I decided to switch to a standard like json. |
Maybe the JSON-like output of the standard formatter as it is now can be made less JSON looking by some easy to implement change, in order to make it less likely that our users would expect for this output to be reliable JSON. Something like this: from json import dumps
from re import sub
data = {1: 2, 3: {4: 5, 6: {3: 6}}}
print(dumps(data, indent=4))
print(sub("\s*{", "", sub("\s*}", "", dumps(data, indent=4)))) |
| util.ns_to_iso_str(self.start_time) if self.start_time else "None", | ||
| util.ns_to_iso_str(self.end_time) if self.end_time else "None", | ||
| ) | ||
| def format_context(context): |
There was a problem hiding this comment.
do these need to be inline functions? why not utility functions outside of the string?
I haven't done the investigation, but I wonder if that's adding overhead by requiring lambdas to be generated dynamically every time str is called.
There was a problem hiding this comment.
I moved them as static functions on the class.
| util.ns_to_iso_str(self.end_time) if self.end_time else "None", | ||
| ) | ||
| def format_context(context): | ||
| x_ctx = OrderedDict() |
There was a problem hiding this comment.
is this necessary? also in python3.7 and above, dicts are always ordered.
There was a problem hiding this comment.
I think so. The main purpose of this exporter is for debugging, so I think guaranteeing that the output order is deterministic will help a lot.
- move helpers methods to be part class instead of inlined functions - use to_json() instead of __str__()
|
I updated the PR to use |
|
I closed it by mistake while cleaning up some branches. It's open and waiting for more reviews. |
codeboten
left a comment
There was a problem hiding this comment.
Just a question re. the http test, otherwise this looks great.
| (sys.executable, test_script) | ||
| ).decode() | ||
| self.assertIn('name="/"', output) | ||
| self.assertIn('"name":', output) |
There was a problem hiding this comment.
Any reason this is changing the test to not check for /?
There was a problem hiding this comment.
Thanks for catching that, updated.
|
Approving this, I think that we can sort out formatting details later, but this is a fantastic step forward on the very hard to read console spans we have now. |
The current version of the exporter prints everything in a single line, making it difficult to read. It's also missing events, links and attributes. This commit changes the console span exporter to use multiple lines and also adds the missing information about attributes, events and links.
* chore: add @obecny in CODEOWNERS * chore: update approvers list
## Which problem is this PR solving?
A function instrumented with OpenTelemetry can't use this extension
today. Sending OTel telemetry from Lambda currently means either running
a collector alongside the function, which the application connects to
over gRPC, or routing telemetry through CloudWatch.
Meanwhile this extension already has a cheaper path: read what the
function writes to stdout, translate it, ship it. It just only
understood Honeycomb's own JSON.
This teaches it OTLP/JSON, so instrumenting with OTel and pointing the
exporter at stdout is enough — no collector process and no socket for
the application to connect to.
## Short description of the changes
Sixteen commits, each independently reviewable, in four groups.
**The feature.** `otlpjson` recognizes an OTLP export request and hands
it to husky; the Telemetry API receiver expands one such record into an
event per span or log record, leaving everything else handled exactly as
before. A later commit adds the `otlp-stdout` envelope — see below for
why.
**Two fixes worth separating out.** A record of JSON `null`, or a
message with no record at all, reached libhoney's `Add` with a nil value
and panicked it, costing the rest of that batch; `main` panics on both
shapes, so this predates the branch. And an export request that
translated to zero spans was handled by no path at all — neither turned
into events nor logged — so it vanished silently.
**Build and docs.** `-s -w` strips the symbol table and DWARF from the
layer zip Lambda downloads at cold start (see the size table below); the
README documents which exporters actually work, which took a correction
after the first version named one that doesn't.
**Testing**, which is most of the commit count: payloads captured from a
real Lambda and replayed through the handler, the extension running
inside a real Lambda runtime, and CI running that on both published
architectures.
Traces and logs. Not metrics.
### Two line formats, because OTLP/JSON alone only reaches Java
This started as OTLP/JSON only, and that turned out to cover one
language. Checking what each SDK can actually emit:
- **Java** can, via `OTEL_TRACES_EXPORTER=experimental-otlp/stdout`
(1.43.0+). Experimental, as named.
- **Node's** `ConsoleSpanExporter` calls `console.dir(…, {depth: 3})` —
Node's inspect format, not JSON, multi-line, elided below depth 3, and
documented as subject to change at any time.
- **Python's** emits the SDK's own span shape via `to_json()`,
multi-line by design since
[#505](open-telemetry/opentelemetry-python#505).
Writing adapters for those console formats would mean parsing output
their own maintainers call unstable and diagnostic-only, so this instead
accepts the [`otlp-stdout`
exporters](https://github.com/dev7a/serverless-otlp-forwarder) that
Node, Python and Rust do have. They emit one JSON line wrapping a
compressed, base64-encoded export request. That takes coverage from one
language to four.
The envelope's declared `content-type` and `content-encoding` are passed
to husky rather than assumed, so protobuf or JSON, gzip or zstd or
uncompressed all work, and a change to the exporters' defaults won't
silently break parsing. The signal comes from the `endpoint` the payload
was addressed to, since a compressed body can't be inspected for it.
Two things worth noting: it costs **nothing** in binary size, because
the protobuf decoder was already linked for the JSON path; and since the
payload is compressed, it fits far more spans into a line before hitting
Lambda's truncation limit — the constraint most likely to bite in
practice.
These are community packages, not part of OpenTelemetry proper. If we'd
rather not build on a third-party envelope, the alternative is Java-only
until upstream ships stdout exporters, and that's a reasonable call to
make in review.
### Why husky rather than a hand-written mapping
`husky/otlp` is the same library Honeycomb's OTLP ingest uses. Reusing
it means field naming, resource-attribute flattening, sample rate,
timestamps and dataset routing are *by construction* identical to what
the same spans would produce through the OTLP endpoint — there's no
second mapping to drift out of sync. The alternative was ~350 lines
re-implementing `trace.parent_id`, `duration_ms`, `span.kind`,
`meta.annotation_type` and friends, and owning that indefinitely.
### Size: husky costs 2.6 MiB, stripping refunds 3.3 MiB
husky pulls in otel-proto and the protobuf runtime, so this was the
first thing measured. x86_64, `zip -9`:
| build | binary | layer zip |
| --- | --- | --- |
| main, as shipped | 16.04 MiB | 7.13 MiB |
| main, `-s -w` | 12.02 MiB | 3.81 MiB |
| this branch, no strip | 26.70 MiB | 12.13 MiB |
| this branch, as it will ship | 19.41 MiB | **6.41 MiB** |
Stating this plainly rather than letting the two commits net out to an
implied win: **husky costs +2.6 MiB zipped and +7.4 MiB on disk, and
every user pays it at cold start whether or not they emit OTLP.** The
shipped layer still shrinks 7.13 → 6.41 MiB (−10%), but that's the
stripping paying for it, and the strip commit stands on its own — it
would be worth taking even if this feature were rejected.
Worth knowing for anyone re-measuring: of husky's cost, the bulk is the
OTLP generated structs plus the protobuf runtime, which resists
dead-code elimination because it registers types reflectively. The
scary-looking transitive deps (gonum, grpc-gateway,
collector-contrib/sampling) *are* eliminated and cost ~0.5 MiB, and
adding the logs entrypoint on top of traces costs nothing measurable.
There is no smaller subset of `husky/otlp` to import — it's a single
package.
### Translated telemetry keeps the extension's marker
Translated OTLP carries `lambda_extension.type`, which the OTLP endpoint
would not add. That is deliberate rather than an oversight: annotating
telemetry with the component that handled it is what Refinery does on
the way through, and it is how a query tells a span that arrived via
this layer from one sent to Honeycomb directly. Documented in the README
and pinned by a test.
### Dataset routing changes for OTLP events only
Spans go to the dataset named by their `service.name`, as they would via
the OTLP endpoint. `LIBHONEY_DATASET` remains the destination for
classic keys and for every non-OTLP record. This is a deliberate
behavior difference from everything else the extension emits; the
alternative — collapsing all services into one configured dataset —
seemed worse than matching the endpoint.
### `LogMessage.Record` is now `json.RawMessage`
This is the largest mechanical part of the diff and the part most worth
a look. The record is kept as raw bytes instead of being decoded to
`interface{}` first, so the translator sees exactly what the function
wrote. Decoding first would round-trip nanosecond timestamps through a
float64 and quietly lose the low bits —
`TestOTLPNumericNanosecondsKeepFullPrecision` covers that case. The cost
is that existing test fixtures now build records as wire JSON rather
than Go maps. No pre-existing test changed its expectations, only its
fixture syntax.
## Testing
Three layers, weakest evidence first.
**Unit tests.** Detection across 12 cases including the near-misses
(`resourceSpans` nested rather than top level, libhoney envelopes,
non-JSON lines); translation of traces and logs; classic-versus-E&S
dataset routing, including husky's asymmetry between the two signals;
husky's sentinel errors rather than merely "an error occurred". Through
the HTTP handler: both of Lambda's log formats, multi-span fan-out,
platform records, malformed OTLP, export requests that translate to
nothing, and record shapes that used to panic libhoney.
**Replay of telemetry captured from a real Lambda function.** Every
fixture used to be one I wrote, which meant the tests confirmed my
beliefs about the wire format rather than the format itself — and one of
those beliefs was already wrong. `telemetryapi/testdata/capture/`
deploys a throwaway function that writes each shape to stdout, records
what the Telemetry API actually delivers, and tears itself down; the
recordings are replayed through the handler. Both log formats are
captured, and asserted to produce **identical** events, which is the
property that makes log format a non-issue for users.
Two things that capture settled, neither of which was knowable by
reading: under JSON log format an already-JSON line arrives
**verbatim**, with no platform keys merged in (extra keys would make
every OTLP payload fail to parse, since protojson rejects unknown
fields); and on a custom runtime a non-JSON line arrives as a bare
string under both formats, so the `{timestamp, level, message}` unwrap
path is still covered only by hand-written tests.
**The extension running inside a real Lambda runtime.** `make test-rie`
builds the extension into the Lambda base image at `/opt/extensions`,
and the platform starts it, registers it, and delivers telemetry over
the real Extensions and Telemetry APIs. The events it sends are decoded
and asserted on: OTLP/JSON traces and logs, the `otlp-stdout` envelope,
a libhoney envelope and a plain log line, plus the rule that only
translated telemetry routes away from the configured dataset. It also
covers the registration lifecycle, including the Lambda Managed
Instances path whose mishandling made an earlier release unusable.
This runs in CI on **both x86_64 and arm64** — arm64 layers are
published and nothing exercised them before — and releases now require
it. The emulator bundled in the base image stubs the Telemetry API, so
the suite builds one that implements it, pinned to a commit;
`EMULATOR_REPO`/`EMULATOR_REF` point it elsewhere, including at a local
checkout.
Claims were checked by mutation rather than assertion — breaking the
implementation and confirming a test notices. The nanosecond-precision
guard, the sample rate reaching the event, the null-record guard, the
function-type gate, the per-event dataset override, OTLP detection and
envelope support all fail their tests when reverted.
**What is still not tested.** The extension itself has never run on a
real Lambda: the capture above deployed a purpose-built recorder, not
this code, and an emulator is not the platform. The Java exporter
guidance is reasoned from upstream sources rather than observed in AWS.
Both remain reasons to try this on real functions before recommending it
to anyone.
### Two rounds of review already applied
An adversarial review pass found things worth recording, since they
shaped the diff:
- The first version of the README named Java's
`OtlpJsonLoggingSpanExporter`. That exporter emits lines with **no
`resourceSpans` wrapper**
([opentelemetry-java#6749](open-telemetry/opentelemetry-java#6749))
and writes through `java.util.logging`, so following the original docs
would have silently produced nothing. `experimental-otlp/stdout` is the
value that works.
- An export request translating to zero spans vanished entirely —
handled by no path, logged by nothing. Now warns and falls through.
- husky routes the signals asymmetrically for classic keys (spans honor
the configured dataset, log records still prefer `service.name`).
Documented and pinned by a test.
- Telling users `LIBHONEY_DATASET` wasn't their destination would have
led some to unset it, which disables the extension completely. The
README now says to keep it.
- A record of JSON `null` panics libhoney and costs the rest of the
batch. **This one predates the branch** — `main` panics identically, and
on the absent-`record` case too. Fixed here since the surrounding code
was already being touched.
## Open questions for review
- **Depending on community exporters.** The `otlp-stdout` packages that
give Node, Python and Rust a working path are from
serverless-otlp-forwarder, not OpenTelemetry proper. Accepting their
envelope is what takes this beyond Java. If we would rather only support
formats that come from upstream, this is Java-only until the OTLP File
exporters stabilize — a legitimate call to make.
- **Truncation stays silent.** Lambda truncates long log lines, and a
truncated payload arrives as a single event carrying the broken text in
a `record` field: no spans, no warning. The README says to keep batches
small, which is advice rather than a safeguard. Should the extension
recognize a truncated OTLP payload and say so?
- **The emulator suite points at a fork.** `test/rie` builds an emulator
with Telemetry API support from a personal fork, pinned to a commit,
because the one in the Lambda base image stubs that API. If [the
upstream
PR](aws/aws-lambda-runtime-interface-emulator#183)
lands, that constant becomes an upstream ref. Reviewers may reasonably
want this suite gated differently until then.
🤖 Generated with [Claude Code](https://claude.com/claude-code)
---------
Co-authored-by: Claude Opus 5 (1M context) <noreply@anthropic.com>
The current version of the exporter prints everything in a single line, making
it difficult to read. It's also missing events, links and attributes.
This commit changes the console span exporter to use multiple lines and also
adds the missing information about attributes, events and links.
Fixes: #478
I started thinking it was a super easy task, then I realized it was more complex than I anticipated. I ended up with this version, I would like to know opinions on this.
Edit: I realized It was getting too messy by handling all the indentation logic and so on. I created a new version that uses json to format the spans.
Example code:
Example output: